feat: identify internal function invocations in traces #8222

klkvr · 2024-06-21T01:05:36Z

Motivation

Introduces --decode-internal flag for forge test, cast run and cast call --trace which enables decoding of internal functions in traces

Example

Example trace of random Uniswap V3 swap:

Solution

To determine when we are jumping in/out of functions we are using source map Jump key. However, it is not really reliable, especially after optimizations. Almost in all cases there are mismatches between number of "in"s and "out"s, so we need additional processing to correctly display subset of functions which are correctly reported.

Main implementation of this tracing is in DebugTraceIdentifier: https://github.com/foundry-rs/foundry/blob/216e9da8a28fcc57bcba1c6c4986aa5353472cc5/crates/evm/traces/src/debug/mod.rs

The only issue with this approach is that we are losing data about entire stack of internal functions which were joined before revert

I've used default tracer from revm-inspectors instead of traces collected by Debugger to allow easier integration into printing logic. Using it required a small patch to inspectors: paradigmxyz/revm-inspectors#150

This approach is enough to implement flamegraphs in a similar way, and can probably be extended to smarter tracking of stack/memory/calldata to also resolve input and output parameters of internal functions

Printing logic is a bit ugly at the moment

Closes: #3999 + Closes: #4351

Adds `Step` variant for `LogCallOrder` enum and renames it to `TraceMemberOrder`. This is useful for printing logic which relies on execution steps as well, e.g. foundry-rs/foundry#8222

klkvr · 2024-06-24T15:11:30Z

Added tracking of inputs and ouputs as well. It is currently not able to decode user-defined types such as structs and enums, tracking those would probably require smarter AST analysis.

Currently --decode-internal is pretty expensive in terms of memory usage because each step is being tracked for each test. We are only interested in JUMPs and JUMPDESTs, so it might make sense to add a configuration option for TracingInspector to only collect steps with specific opcodes.

mattsse

only briefly skimmed parts of it.

I think this makes sense, I'd appreciate a few more docs, and I'll take a closer look

crates/cli/src/utils/cmd.rs

mattsse · 2024-06-25T19:08:48Z

crates/evm/evm/src/inspectors/stack.rs

+        if self.tracer.is_none() && yes ||
+            !self.tracer.as_ref().map_or(false, |t| t.config().record_steps) && debug


this is a bit hard to follow,
I wonder if we can encapsulate these two bools into an enum TracingKid or smth, because debug also implies tracing, right?

- Adds `record_returndata_snapshots` flag to config which enables snapshots of `interpreter.return_data_buffer` - Adds `record_opcodes_filter` parameter which allows to only record specific opcodes. ref foundry-rs/foundry#8222 (comment) - Adds `gas_used` field for `CallTraceStep` This should be enough to migrate foundry's debugger to using `TracingInspector` from here, I will open PR for this later today.

ref foundry-rs/foundry#8222 ref foundry-rs/foundry#8198 Adds structs and extends `TraceWriter` to support formatting of decoded trace steps. Currently two decoding formats are supported: - Internal calls. Similar to a decoded call trace, decoded internal function invocation which spans over multiple steps. Kept as decoded function name, inputs, outputs and index of the last step. - Arbitrary strings. This might be useful for formatting decoded opcodes (e.g. adding `├─ [sload] <slot>` to trace. It might make sense to extend it to something more configurable once we start implementing this

mattsse

lgtm

pending @DaniPopes

crates/forge/src/multi_runner.rs

crates/evm/traces/src/debug/sources.rs

crates/evm/evm/src/executors/trace.rs

crates/evm/traces/src/debug/sources.rs

klkvr · 2024-07-09T14:29:41Z

Updated --decode-internal flag to accept a regex similar to --debug. On large suites --decode-internal easily results in OOM, so I think it's better to restrict its usage in such way

DaniPopes · 2024-07-09T16:12:37Z

Yeah same problem as in the debugger caused by memory snapshots

DaniPopes · 2024-07-09T16:17:37Z

Maybe we can disable memory decoding by default to avoid the memory consumption issue?

klkvr · 2024-07-09T17:10:32Z

Maybe we can disable memory decoding by default to avoid the memory consumption issue?

Yeah, I though about disabling memory tracking if more than one test matched filters. Though not sure how to make this intuitive

Should it be two separate flags, one of which does not require the test function filter?

klkvr · 2024-07-11T13:31:33Z

Updated forge test --decode-internal flag to only accept test function parameter optionally:

--decode-internal [<TEST_FUNCTION>]
  Whether to identify internal functions in traces.
  
  If no argument is passed to this flag, it will trace internal functions scope and decode stack parameters, but parameters stored in memory (such as bytes or arrays) will not be
  decoded.
  
  To decode memory parameters, you should pass an argument with a test function name, similarly to --debug and --match-test.
  
  If more than one test matches your specified criteria, you must add additional filters until only one test is found (see --match-contract and --match-path).

crates/forge/bin/cmd/test/mod.rs

Philogy · 2024-07-17T21:51:55Z

Hey @klkvr, great work on this PR!

Just wanted to follow up on your comment about source maps getting messed up by the optimization step: do you mean that they're actually broken and it'd be useful to open an issue in solc or just that optimization fundamentally obfuscates the origin of an opcode as they could be reduced to fewer operations?

klkvr · 2024-07-18T16:06:17Z

@Philogy it's hard to tell, I've definitely seen situations in which source maps would point to completely unrelated chunck of code for some of the instructions after optimizations. However, I wouldn't be surprised if this has a reasonable explanation related to how inlining works internally. Sourcemaps are documented very briefly so it's hard to tell how they should behave and what we should consider a bug, and whether we can trust them after certain number of optimizations at all

m-waqas88 · 2024-09-17T19:41:02Z

Version: forge 0.2.0 (41d4e54 2024-09-17T00:21:10.066464000Z)

Hey guys, really appreciate your efforts. I am actually facing an issue, when using --decode-internal flag, the value of arguments shown in the trace is actually wrong, as you can see I have logged the actual values pass as arguments. epoch is the first parameter and account is the second one. Console logging is showing correct values but in call trace (as function inputs) this value is incorrect.

Notes:

In foundry.toml --via-ir is set to true (I cannot disable it otherwise it will throw stack too deep error)
forge test --mp VaultWY.t.sol --mt test_WY_withdrawAndClaim -vvv --decode-internal --fork-url <fork-url>

@klkvr

m-waqas88 · 2024-09-18T08:03:22Z

Version: forge 0.2.0 (41d4e54 2024-09-17T00:21:10.066464000Z)

Hey guys, really appreciate your efforts. I am actually facing an issue, when using --decode-internal flag, the value of arguments shown in the trace is actually wrong, as you can see I have logged the actual values pass as arguments. epoch is the first parameter and account is the second one. Console logging is showing correct values but in call trace (as function inputs) this value is incorrect.

Notes:

In foundry.toml --via-ir is set to true (I cannot disable it otherwise it will throw stack too deep error)

forge test --mp VaultWY.t.sol --mt test_WY_withdrawAndClaim -vvv --decode-internal --fork-url <fork-url>

@klkvr

Ok I got it. first parameter 1335805085125855948948476260874682295582732906387 is the decimal representation of the address --> waqas, and the second parameter is the hex representation of zero 0.

fix: small debugger updates

0460633

klkvr mentioned this pull request Jun 21, 2024

feat: Add Step to LogCallOrder paradigmxyz/revm-inspectors#150

Merged

[wip] feat: identify internal function invocations in traces

9fd779a

klkvr force-pushed the klkvr/internal-fns-in-traces branch from 3b2b1fe to 9fd779a Compare June 21, 2024 01:24

klkvr added 3 commits June 21, 2024 04:36

fmt

83c7a23

doc

b1a365f

correctly enable tracing

2d17d37

klkvr added 6 commits June 22, 2024 23:29

correctly enable tracing

4728d2e

collect contract definition locs

5ed1abf

feat: print traces in format of Contract::function

6518cb9

Merge branch 'master' into klkvr/internal-fns-in-traces

a038e05

wip

06dc30a

refactor

216e9da

klkvr force-pushed the klkvr/internal-fns-in-traces branch from 5f643a4 to 216e9da Compare June 23, 2024 05:17

clippy

d92f436

klkvr mentioned this pull request Jun 23, 2024

feat(forge): add support for flamegraph #7761

Closed

klkvr added 3 commits June 23, 2024 08:28

fix doc

7fa698b

track input/output values

b3ef110

Merge branch 'master' into klkvr/internal-fns-in-traces

3d59b3f

clippy

5972083

klkvr mentioned this pull request Jun 24, 2024

feat: small updates for steps tracing paradigmxyz/revm-inspectors#152

Merged

zerosnacks mentioned this pull request Jun 25, 2024

Support for internal function jump trace #4351

Closed

mattsse requested changes Jun 25, 2024

View reviewed changes

zerosnacks mentioned this pull request Jun 26, 2024

Best in class Gas Reporting #1795

Closed

klkvr added 3 commits June 26, 2024 12:36

clean up

e9e97a0

Merge branch 'master' into klkvr/internal-fns-in-traces

44e976d

TraceMode

08fd6c5

Merge branch 'master' into klkvr/internal-fns-in-traces

3a01a97

zemse mentioned this pull request Jun 30, 2024

[WIP] Support for Flamegraph #8315

Closed

klkvr mentioned this pull request Jul 1, 2024

feat: add decoding for individual trace steps paradigmxyz/revm-inspectors#157

Merged

Merge branch 'master' into klkvr/internal-fns-in-traces

0031d77

mattsse approved these changes Jul 9, 2024

View reviewed changes

Merge branch 'master' into klkvr/internal-fns-in-traces

e9ec97e

DaniPopes reviewed Jul 9, 2024

View reviewed changes

klkvr added 2 commits July 9, 2024 17:00

review fixes

ec783d6

--decode-internal for single fn

ff2a11b

klkvr added 5 commits July 10, 2024 00:17

use Vec

e46c017

TraceMode builder

062d550

Merge branch 'master' into klkvr/internal-fns-in-traces

5568fc7

optional --decode-internal and tests

9db774f

update doc

97c2b4b

klkvr requested a review from DaniPopes July 11, 2024 13:39

DaniPopes approved these changes Jul 11, 2024

View reviewed changes

crates/forge/bin/cmd/test/mod.rs Outdated Show resolved Hide resolved

InternalTraceMode

92ece42

mattsse approved these changes Jul 11, 2024

View reviewed changes

DaniPopes merged commit 6bb5c8e into master Jul 11, 2024
21 checks passed

DaniPopes deleted the klkvr/internal-fns-in-traces branch July 11, 2024 16:20

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: identify internal function invocations in traces #8222

feat: identify internal function invocations in traces #8222

klkvr commented Jun 21, 2024 •

edited by zerosnacks

Loading

klkvr commented Jun 24, 2024 •

edited

Loading

mattsse left a comment

mattsse Jun 25, 2024

mattsse left a comment

klkvr commented Jul 9, 2024 •

edited

Loading

DaniPopes commented Jul 9, 2024

DaniPopes commented Jul 9, 2024

klkvr commented Jul 9, 2024

klkvr commented Jul 11, 2024

Philogy commented Jul 17, 2024

klkvr commented Jul 18, 2024

m-waqas88 commented Sep 17, 2024

m-waqas88 commented Sep 18, 2024

		if self.tracer.is_none() && yes \|\|
		!self.tracer.as_ref().map_or(false, \|t\| t.config().record_steps) && debug

feat: identify internal function invocations in traces #8222

feat: identify internal function invocations in traces #8222

Conversation

klkvr commented Jun 21, 2024 • edited by zerosnacks Loading

Motivation

Example

Solution

klkvr commented Jun 24, 2024 • edited Loading

mattsse left a comment

Choose a reason for hiding this comment

mattsse Jun 25, 2024

Choose a reason for hiding this comment

mattsse left a comment

Choose a reason for hiding this comment

klkvr commented Jul 9, 2024 • edited Loading

DaniPopes commented Jul 9, 2024

DaniPopes commented Jul 9, 2024

klkvr commented Jul 9, 2024

klkvr commented Jul 11, 2024

Philogy commented Jul 17, 2024

klkvr commented Jul 18, 2024

m-waqas88 commented Sep 17, 2024

m-waqas88 commented Sep 18, 2024

klkvr commented Jun 21, 2024 •

edited by zerosnacks

Loading

klkvr commented Jun 24, 2024 •

edited

Loading

klkvr commented Jul 9, 2024 •

edited

Loading